CloudWatch Logs InsightsでALBのELB 5XX発生時のアクセスログを分析してみた

AWSチームのすずきです。

ALBのELB 5XX発生時の解析のため、アクセスログをパース、CloudWatch Logsに転送するLambda関数を用意。 Amazon CloudWatch Logs Insights で可視化する機会がありましたので、紹介させていただきます。

Lambda

パーサー

• Python 3.7 のランタイム、「re」正規表現モジュールを利用しました。

import re

RE_TEXT = r"""
  ^(?P<type>[^ ]*)\u0020
  (?P<time>[^ ]*)\u0020
  (?P<elb>[^ ]*)\u0020
  (?P<client_ip>[^ ]*):(?P<client_port>[0-9]*)\u0020
  (?P<target_ip>[^ ]*)[:-](?P<target_port>[0-9]*)\u0020
  (?P<request_processing_time>[-.0-9]*)\u0020
  (?P<target_processing_time>[-.0-9]*)\u0020
  (?P<response_processing_time>[-.0-9]*)\u0020
  (?P<elb_status_code>|[-0-9]*)\u0020
  (?P<target_status_code>-|[-0-9]*)\u0020
  (?P<received_bytes>[-0-9]*)\u0020
  (?P<sent_bytes>[-0-9]*)\u0020
  \"(?P<request_method>[^ ]*)\u0020
  (?P<request_url>[^ ]*)\u0020
  (?P<request_http_version>- |[^ ]*)\"\u0020
  \"(?P<user_agent>[^\"]*)\"\u0020
  (?P<ssl_cipher>[A-Z0-9-]+)\u0020
  (?P<ssl_protocol>[A-Za-z0-9.-]*)\u0020
  (?P<target_group_arn>[^ ]*)\u0020
  \"(?P<trace_id>[^\"]*)\"\u0020
  \"(?P<domain_name>[^\"]*)\"\u0020
  \"(?P<chosen_cert_arn>[^\"]*)\"\u0020
  (?P<matched_rule_priority>[-.0-9]*)\u0020
  (?P<request_creation_time>[^ ]*)\u0020
  \"(?P<actions_executed>[^\"]*)\"\u0020
  \"(?P<redirect_url>[^\"]*)\"\u0020
  \"(?P<error_reason>[^\"]*)\"
  (?P<new_field>.*)
  """
RE_FORMAT = re.compile(RE_TEXT, flags=re.VERBOSE)

• 正規表現 と カラム名は Amazon Athena のユーザガイドに準拠しました。

Application Load Balancer ログのクエリ

• ALBの機能追加にあわせてアクセスログの仕様も更新されています。追加された項目が 従来のログの末尾以外に追加された場合、正規表現の修正が必要になる点はご留意下さい。

AZ、ELBノードIP

• S3のログファイル名より ELBノードのIPを取得、アベイアビリティゾーンを求めました。

https://dev.classmethod.jp/cloud/aws/add-az-alb-accesslog/

  elb_listener_ip = s3key.split('_')[-2]
  d = {}
  if len(elb_listener_ip) > 4:
    d["elb_listener_ip"] = elb_listener_ip
    r = ec2.describe_network_interfaces(
      Filters=[{'Name':'association.public-ip','Values':[elb_listener_ip]}]
    )
    if ("NetworkInterfaces" in r):
      d["elb_availabilityzone"] = r["NetworkInterfaces"][0]["AvailabilityZone"]
      d["elb_private_ip"] = r["NetworkInterfaces"][0]["PrivateIpAddress"]

テスト

Application Load Balancer のアクセスログ に記載された ログサンプルのパースを試みました。

  import json
  log_h2 = 'h2 2018-07-02T22:23:00.186641Z app/my-loadbalancer/50dc6c495c0c9188 10.0.1.252:48160 10.0.0.66:9000 0.000 0.002 0.000 200 200 5 257 "GET https://10.0.2.105:773/ HTTP/2.0" "curl/7.46.0" ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067 "Root=1-58337327-72bd00b0343d75b906739c42" "-" "-" 1 2018-07-02T22:22:48.364000Z "redirect" "https://example.com:80/" "-"'
  a = RE_FORMAT.match(log_h2).groupdict()
  a.update(d)
  print(json.dump(a))

• 出力結果

{
  "type": "h2",
  "time": "2018-07-02T22:23:00.186641Z",
  "elb": "app/my-loadbalancer/50dc6c495c0c9188",
  "client_ip": "10.0.1.252",
  "client_port": "48160",
  "target_ip": "10.0.0.66",
  "target_port": "9000",
  "request_processing_time": "0.000",
  "target_processing_time": "0.002",
  "response_processing_time": "0.000",
  "elb_status_code": "200",
  "target_status_code": "200",
  "received_bytes": "5",
  "sent_bytes": "257",
  "request_method": "GET",
  "request_url": "https://10.0.2.105:773/",
  "request_http_version": "HTTP/2.0",
  "user_agent": "curl/7.46.0",
  "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
  "ssl_protocol": "TLSv1.2",
  "target_group_arn": "arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067",
  "trace_id": "Root=1-58337327-72bd00b0343d75b906739c42",
  "domain_name": "-",
  "chosen_cert_arn": "-",
  "matched_rule_priority": "1",
  "request_creation_time": "2018-07-02T22:22:48.364000Z",
  "actions_executed": "redirect",
  "redirect_url": "https://example.com:80/",
  "error_reason": "-",
  "new_field": "",
  "elb_availabilityzone": "us-east-2a"
  "elb_private_ip": "172.xx.xx.xx"
}

ELB 5XX抽出

ターゲットのEC2応答(target_status_code)が「500」台応答を戻さず、ELB(ALB)応答(elb_status_code)が「500」台、ELB 5XX に該当するログレコードのみを抽出します。

if a["elb_status_code"][0:1] == '5':
    if not a["target_status_code"][0:1] == '5':
        print(json.dumps(a))

正常系のログを除外する事で、CloudWatch Logsのデータ取り込み課金(0.76USD/GB @東京)、Insightsのクエリ課金(スキャンしたデータ 1 GB あたり 0.0076USD)を抑制します。

Loggerは、Lambda標準のものを利用しました。 任意のロググループ、ログストリームを出力先とする場合、CloudWatch Logs の制限 にご注意ください。

• CloudWatch Logs の制限

CloudWatchLogs

CloudWatchLogs Insight

CloudWatchLogs Insightで、分析対象のロググループと期間を指定して分析を試みました。

• elb_status_code 500〜599までのログを10件抽出

fields @message
| sort @time desc
| filter elb_status_code like /5\d\d/
| limit 10

• ログ行を指定、詳細を確認可能です。

• アベイアビリティゾーン別の ELB 5XX ログ件数を集計

stats count(elb_availabilityzone) as count_elb_az by elb_availabilityzone
| filter elb_status_code like /5\d\d/
| sort count_elb_az desc

• ELBノードIP、actions_executed 別ログ件数を集計

stats count(actions_executed) as count_actions_executed by actions_executed, elb_listener_ip
| filter elb_status_code like /5\d\d/
| sort count_actions_executed desc

まとめ

ALBの ELB 5XX エラーを示したアクセスログ、AWSコンソールを利用して簡単に確認する事が可能となりました。

AWS WAF、認証、Lambda などを利用するALBでは、ELB 5XXエラー発生時、原因特定のためにアクセスログ情報が必要となる事があります。 Amazon Athena よりも 簡単に利用しやすい仕組みが必要な場合、今回の仕組みをお試し下さい。

Application Load Balancer のトラブルシューティング

尚、ELB 5XX、及び エラーコード別のエラー件数 については、ALB の CloudWatchのメトリックで確認する事が可能です。 迅速なエラー通知を必要とする場合、こちらを対象としたアラームもお試し下さい。

• ELB 5XX エラーコード一覧

レスポンスコード	Metric (ALB)	説明
500-599	HTTPCode_ELB_5XX_Count	ロードバランサーから送信される HTTP 5XX サーバーエラー
500	HTTPCode_ELB_500_Count	内部サーバーエラー
501	-	Not Implemented
502	HTTPCode_ELB_502_Count	Bad Gateway
503	HTTPCode_ELB_503_Count	Service Unavailable
504	HTTPCode_ELB_504_Count	Gateway Timeout
561	-	Unauthorized

CloudFormation

今回紹介したLambda、S3を展開するCloudFormationテンプレートです。

構成図

テンプレート

• alb-accesslog-cw-log.yaml